fix(plugins): one hung plugin no longer stops every plugin from updating - #677

Problem

PluginManager._update_worker_loop() is the only thread that runs scheduled update() calls. It took each plugin's lock with a blocking lock.acquire(), with no timeout. The render thread holds that same lock while it runs the plugin's display(). If one plugin's display() never returns, the worker blocks on that acquire forever and no plugin updates again. The display keeps scrolling, but scores, weather and clocks go stale. The same thing happens when a screen's first frame outlives PluginExecutor's 30s timeout: its lingering daemon thread keeps the lock indefinitely.

Related gaps:

• After a screen's first frame, display() calls were not timed at all.
• A first frame that timed out was still recorded as a health success.
• An update() still running after its timeout left the plugin in RUNNING state with nothing recorded.
• on_config_change() (overridden by ~45 plugins) ran on the config watcher thread without the plugin lock, so it could interleave with update() on the worker.

Fix

This PR only contains hangs inside the process. It does not change the systemd units or the installer.

• Bounded lock wait on the worker. The worker waits at most PluginManager.PLUGIN_LOCK_TIMEOUT (5s), which is UNLOAD_LOCK_TIMEOUT, the bound unload already uses for this lock. A display() frame holds the lock for milliseconds, but a Vegas prefetch holds it for the plugin's whole content render, which on a slow Pi can outlast 5s. When the wait runs out, _skip_busy_update():

  • drops the pending slot;
  • returns the plugin to ENABLED with PluginBusyError error info (the existing _record_update_failure bookkeeping, with count_failure=False);
  • stamps the last-update time, so the retry waits a full interval;
  • logs it, rate-limited to once a minute per plugin;
  • records it in health as a busy skip (busy_skip_count, last_busy_skip, via the new PluginHealthTracker.record_busy_skip).

  A busy skip is report-only (owner decision): it never touches the failure streak, last_error or the circuit breaker, so a healthy plugin whose lock a Vegas render holds is never pulled from rotation. Only real hangs count toward the breaker: display() or update() running past the executor timeout (below). The other plugins keep updating. If the plugin is unloaded while the worker waits, nothing is resurrected. Busy-skip persistence shares the slow-call throttle: the first one is saved at once (so the web process's health API sees it), then at most once a minute per plugin.

• display() timing. DisplayController._display_once times every frame with two time.monotonic() reads. The first-frame dispatch is timed too. Both report to PluginManager.note_display_duration():

  • Under PluginExecutor.SLOW_DISPLAY_SECONDS (2s): one compare, nothing else.
  • 2s or more: logged at most once a minute per plugin, with a count of suppressed repeats. Counted in health as slow_call_count / last_slow_call. This is reporting only and does not affect the circuit breaker. It is saved to disk at most once a minute per plugin (SD wear).
  • At or past the executor timeout: recorded as a hang, via PluginHealthTracker.record_hang → record_failure.
  • A first frame still running when the executor gives up is recorded as a hang, not a success.

• Hung update(). When the executor stops waiting on the async path, the plugin is recorded as hung and a warning is logged. If the late update() eventually returns, record_success clears the failure streak.

• on_config_change serialised. The hot-reload callback now calls PluginManager.apply_config_change(). It runs on_config_change on the calling thread while holding the plugin's lock, with the same timed acquire. If the lock stays busy, the change is parked (latest one wins) and a _DeferredConfigChange item is queued. The worker applies it under the lock as soon as the lock is free, and at the latest just before the plugin's next update(). A parked change meant for an instance that has since been reloaded is dropped. Exceptions on the immediate path still reach the caller as before.

• The plugin-facing API is unchanged. Health summaries gain six fields: hang_count, last_hang, slow_call_count, last_slow_call, busy_skip_count, last_busy_skip.

Thread model (also in a comment in PluginManager.__init__)

Tests

New test/test_plugin_hang_containment.py has 24 tests and runs in about 10s, using timeouts of 0.1–0.3s. It covers:

• A fake plugin's display() blocks on an Event while holding its lock. Another plugin's update() keeps running on schedule, and the worker stays alive.
• The timed-out acquire is recorded as a busy skip (busy_skip_count, last_busy_skip, PluginBusyError in the state error info) with no failure, hang or last_error. Nine busy skips in a row (3x the threshold) leave the breaker closed, and the plugin updates normally once the lock frees. Busy skips do not extend an existing hang streak. Repeated real hangs still open the breaker after exactly failure_threshold, with busy skips interleaved. The skip is logged once per interval. Unloading during the wait does not resurrect the plugin. Busy-skip persistence is rate-limited and breaker-free.
• An update() that outlives the executor timeout is recorded as a hang and cleared once it returns.
• display() timing: fast frames record nothing; slow frames are recorded and warned about once, with the suppressed count shown on the next warning; frames past the timeout count as hangs; _display_once passes each frame's duration on and does not time skipped frames.
• on_config_change does not run concurrently with update() and runs holding the lock. When the lock is busy, the latest change is deferred and applied before the next update(), or by the worker once the lock frees. Stale changes are dropped after a reload. Exceptions still reach the caller.
• record_slow_call saves to disk at most once a minute, and hang records survive a restart.

Mutation check (report-only): with _skip_busy_update counting the skip as a failure again, the four busy-skip/real-hang tests fail. Mutation check: with the worker's acquire changed back to a blocking lock.acquire(), the three worker tests fail. With the fix they pass; three consecutive runs showed no flakes.

test/test_plugin_config_preparation.py: the two hot-reload tests now delegate the mocked manager's apply_config_change to a real PluginManager, so they still check that the plugin receives the prepared config.

Full suite vs baseline (Windows, Python 3.14, Pillow 12.3.0 before and after, pytest -m "not hardware" test/ --ignore=test/plugins), rerun after the report-only change at 089a177. The baseline is a separate worktree of c4c46d3 (the branch's merge base with main), with the same config.json copied in.

• Baseline: 59 failed, 6068 passed, 136 skipped, 6 errors.
• Branch: 59 failed, 6092 passed, 136 skipped, 6 errors.
• Diff of the ^(FAILED|ERROR) test/ IDs: identical (65 each, none new, none fixed); all are pre-existing Windows failures.
• Plugin-system tests (test/test_plugin_*.py, async updates, health API, Vegas adapter, display-controller toggle, base plugin): 400 passed.
• mypy ratchet (scripts/check_types.py): at the first commit plugin_executor.py and plugin_health.py were clean (only the existing src/deprecation.py error, from a newer local mypy). mypy is not installed on the host used for the report-only follow-up, so it was not re-run; pyflakes is clean on the changed files. plugin_manager.py is not on the ratchet.

Hardware soak (ledpi, 2026-09-29)

Pi 4, 2x96x48 chain (192x48), pwm_bits 9, gpio_slowdown 8, cap 120 Hz, stock binding. scripts/frame_soak.py --preview --duration 300 after a fresh restart of both services and a 120s warm-up, run in the order main / branch / main / branch (main = c4c46d3, this branch's merge base; branch = 089a177). Workload: baseball + football scoreboards switched to scroll display mode, plus news (ticker) and clock-simple (1s update interval, so the update worker is busy); Vegas runs the same with vegas_scroll.enabled. The rig's config was restored byte-identical afterwards.

* the soak graded these NOT LOCKED (frames measured at ~126 Hz against a 120 Hz cap: Vegas asks for 125 fps), so the Vegas late count is only comparable between builds, not graded. The same holds on main.

• No measurable frame cost from the per-frame display() timing: rotation late rate 0.088% / 0.088% on the branch vs 0.094% / 0.101% on main; freezes identical (9 per run, the same 5 render stalls per run on both builds, from content fetched on the render thread).
• Plugin health (/api/v3/plugins/health after every run, and the journal): no plugin had a hang, a slow display(), a busy skip or an open circuit on either build. busy_skip_count stayed 0 in all Vegas runs, so the prefetch never held a lock for 5s on this rig. The only non-closed circuit was countdown (disabled, not in the workload), left open by an earlier deliberate-failure test on the rig on both builds.
• Not exercised on this rig: a Vegas render long enough to cause a busy skip. The unit tests cover that path (report-only, breaker stays closed).

Follow-up (not in this PR)

A render thread that is itself stuck inside display() can only be caught from outside the process. Planned follow-up:

• the display loop pets an sd_notify watchdog (WatchdogSec= in ledmatrix.service) and writes a heartbeat under /run;
• systemd restarts the service when the loop stops.

That changes the unit files and the installer, so it needs Linux/installer proof (root and non-root installs) before merge.

🤖 Generated with Claude Code